Extreme values in downloading directory information
Sometimes it takes a really long time until Tor has downloaded enough directory information to build circuits. In an experiment with 1,220 attempts to start new Tor instances, the following times were measured for downloading directory information (in seconds):
Min. 1st Qu. Median Mean 3rd Qu. Max. 1.732 5.016 7.602 35.680 17.210 681.300
The highest 50 values are:
141.560 151.013 151.880 164.672 169.010 184.269 184.280 187.733 207.903 222.899 238.430 248.529 250.513 252.959 265.249 269.104 281.840 295.144 307.421 307.719 307.863 307.940 308.403 308.438 308.672 308.730 308.741 309.053 309.293 309.357 309.839 310.033 310.259 310.275 311.930 313.203 313.385 313.597 315.260 317.916 318.327 325.420 362.017 367.175 452.797 487.972 489.534 537.029 615.759 681.341
A look at the log files reveals that Tor attempts to fetch network statuses or authority certificates from a single directory that is unavailable at the moment. The request times out after 120 seconds, and another attempt is made---possibly to the same directory. During the measurements, dannenberg appeared to be offline, so that attempts to that authority timed out:
egrep "Bootstrap|86.59.21.38|216.224.124.114|213.73.91.31|141.13.4.202|128.31.0.34|194.109.206.212" log Nov 01 08:42:02.390 [info] Bootstrapped 0%: Starting. Nov 01 08:42:02.390 [info] connection_ap_make_link(): Making internal direct tunnel to 194.109.206.212:443 ... Nov 01 08:42:02.391 [notice] Bootstrapped 5%: Connecting to directory server. Nov 01 08:42:02.393 [info] connection_ap_make_link(): Making internal direct tunnel to 213.73.91.31:443 ... Nov 01 08:42:02.393 [info] directory_send_command(): Downloading consensus from 213.73.91.31:443 using /tor/status-vote/current/consensus.z Nov 01 08:42:02.413 [notice] Bootstrapped 10%: Finishing handshake with directory server. Nov 01 08:42:02.603 [info] command_process_versions_cell(): Negotiated version 2 with 194.109.206.212; sending NETINFO. Nov 01 08:42:02.604 [notice] Bootstrapped 15%: Establishing an encrypted directory connection. Nov 01 08:42:02.605 [info] command_process_netinfo_cell(): Got good NETINFO cell from 194.109.206.212; OR connection is now open, using protocol version 2 Nov 01 08:42:02.693 [notice] Bootstrapped 20%: Asking for networkstatus consensus. Nov 01 08:42:02.790 [info] connection_dir_client_reached_eof(): Received authority certificates (size 9804) from server '194.109.206.212:443' Nov 01 08:42:35.033 [info] command_process_versions_cell(): Negotiated version 2 with 213.73.91.31; sending NETINFO. Nov 01 08:44:02.857 [info] connection_ap_expire_beginning(): Tried for 120 seconds to get a connection to 213.73.91.31:443. Giving up. (waiting for circuit) Nov 01 08:44:02.857 [info] connection_ap_make_link(): Making internal direct tunnel to 213.73.91.31:443 ... Nov 01 08:44:02.858 [info] directory_send_command(): Downloading consensus from 213.73.91.31:443 using /tor/status-vote/current/consensus.z Nov 01 08:46:02.317 [info] connection_ap_expire_beginning(): Tried for 120 seconds to get a connection to 213.73.91.31:443. Giving up. (waiting for circuit) Nov 01 08:47:07.565 [info] connection_ap_make_link(): Making internal direct tunnel to 213.73.91.31:443 ... Nov 01 08:47:07.565 [info] directory_send_command(): Downloading consensus from 213.73.91.31:443 using /tor/status-vote/current/consensus.z Nov 01 08:47:35.669 [info] run_connection_housekeeping(): Expiring non-open OR connection to fd 16 (213.73.91.31:443). Nov 01 08:47:35.669 [info] connection_ap_fail_onehop(): Closing onehop stream to '$7BE683E65D48141321C5ED92F075C55364AC7123/213.73.91.31' because the OR conn just failed. Nov 01 08:53:13.929 [info] connection_ap_make_link(): Making internal direct tunnel to 216.224.124.114:9090 ... Nov 01 08:53:13.930 [info] directory_send_command(): Downloading consensus from 216.224.124.114:9090 using /tor/status-vote/current/consensus.z Nov 01 08:53:15.788 [info] command_process_versions_cell(): Negotiated version 2 with 216.224.124.114; sending NETINFO. Nov 01 08:53:15.788 [info] command_process_netinfo_cell(): Got good NETINFO cell from 216.224.124.114; OR connection is now open, using protocol version 2 Nov 01 08:53:16.677 [notice] Bootstrapped 25%: Loading networkstatus consensus. Nov 01 08:53:21.322 [info] connection_dir_client_reached_eof(): Received consensus directory (size 256583) from server '216.224.124.114:9090' Nov 01 08:53:21.345 [notice] Bootstrapped 45%: Asking for relay descriptors. Nov 01 08:53:21.742 [notice] Bootstrapped 50%: Loading relay descriptors. Nov 01 08:53:22.105 [notice] Bootstrapped 59%: Loading relay descriptors. Nov 01 08:53:22.652 [notice] Bootstrapped 69%: Loading relay descriptors. Nov 01 08:53:23.092 [notice] Bootstrapped 80%: Connecting to the Tor network. Nov 01 08:53:24.408 [notice] Bootstrapped 90%: Establishing a Tor circuit. Nov 01 08:53:25.394 [notice] Bootstrapped 100%: Done. Nov 01 08:53:59.577 [info] connection_ap_make_link(): Making internal anonymized tunnel to 141.13.4.202:443 ... Nov 01 09:08:24.117 [info] run_connection_housekeeping(): Expiring non-used OR connection to fd 15 (194.109.206.212:443) [Not in clique mode].
Possible fixes could be shorter timeouts or parallel requests. However, these fixes have side-effects on network load. Maybe there is also a way to detect and exclude unavailable directory more quickly (requests are tunneled directory requests using one-hop circuits).
[Automatically added by flyspray2trac: Operating System: All]